errors when running concurrently about ixmp

[gidden]

Just for posterity, there are a number of questions (from expert users!) about when exactly to set_as_default(), so it would probably be good to have an FAQ or similar page on that. Also, what is the difference between scen.clone() (without new model/scenario name) and making edits and committing vs just making edits and committing. Frankly, we could probably all use a refresher course on the pseudo-version-control implemented on the ixmp backend.

[gidden]

There are a few things happening here that @OFR-IIASA and I don't understand, but to start, there is a commit happening when loading the scenario which could be culprit (don't know why it happens):

2018-11-21 09:39:31,636 INFO at.ac.iiasa.ixmp.objects.Scenario:1826 - committing changes of Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18489)...

[gidden]

any thoughts @zikolach or @danielhuppmann ?

[danielhuppmann]

When touching a scenario that was created with MESSAGEix v1.0 for the first time with MESSAGEix v1.1, the scenario will be updated (new sets and parameters initialised). This should happen only once for any scenario.

It could be that two processes happening virtually simultaneously result in a conflict here, as both processes load the same scenario and try to update it.

Did you touch this scenario first with only one process? If not, try n=1 first, and then again n>1.

[gidden]

Yes, I also just came to this conclusion. I agree with you that it should work. Let me test and I'll get back to you.

[gidden]

Unfortunately, it looks like it's somehow not actually being saved?

In the first instance (n=1), we see the commit log message. That is seen again after as well (n=4).

In [3]: n=1; pool=multiprocessing.Pool(n); pool.map(subprocess.call, [('python', 'foo.py')] * n)
INFO:root:launching ixmp.Platform using config file at '/home/gidden/work/iiasa/message/properties_files/enedb.properties'
Nov 21, 2018 10:04:52 AM org.flywaydb.core.internal.util.VersionPrinter printVersion
INFO: Flyway 4.2.0 by Boxfuse
Nov 21, 2018 10:04:52 AM org.flywaydb.core.internal.dbsupport.DbSupportFactory createDbSupport
INFO: Database: jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3 (Oracle 12.1)
Nov 21, 2018 10:04:53 AM org.flywaydb.core.internal.command.DbValidate validate
INFO: Successfully validated 11 migrations (execution time 00:00.034s)
2018-11-21 10:04:53,395  INFO at.ac.iiasa.ixmp.Platform:111 - Welcome to the IX modeling platform!
2018-11-21 10:04:53,401  INFO at.ac.iiasa.ixmp.Platform:112 -  connected to database 'ixENE-DB@GP3'...
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:171: UserWarning: The constructor `mp.Scenario()` is deprecated, please use `ixmp.Scenario(mp, ...)`
  warnings.warn('The constructor `mp.Scenario()` is deprecated, '
2018-11-21 10:04:53,477  INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 1, runid: 18489)...
2018-11-21 10:04:53,797  INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
2018-11-21 10:04:53,838  INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 -  spatial and temporal disaggregation maps assignment
2018-11-21 10:04:53,877  INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 -  period mapping assignment
2018-11-21 10:04:53,886  INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 -  duration period assignment
2018-11-21 10:04:53,913  INFO at.ac.iiasa.ixmp.objects.Scenario:1826 - committing changes of Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18489)...
2018-11-21 10:04:55,250  INFO at.ac.iiasa.ixmp.objects.Scenario:601 - done updating Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18489, version: 1)!
2018-11-21 10:04:55,254  INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 -  spatial and temporal disaggregation maps assignment
2018-11-21 10:04:55,254  INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 -  period mapping assignment
2018-11-21 10:04:55,255  INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 -  duration period assignment
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:468: UserWarning: Using `ixmp.Scenario` for MESSAGE-scheme scenarios is deprecated, please use `message_ix.Scenario`
  warnings.warn('Using `ixmp.Scenario` for MESSAGE-scheme scenarios '
Out[3]: [0]

In [4]: n=4; pool=multiprocessing.Pool(n); pool.map(subprocess.call, [('python', 'foo.py')] * n)
INFO:root:launching ixmp.Platform using config file at '/home/gidden/work/iiasa/message/properties_files/enedb.properties'
INFO:root:launching ixmp.Platform using config file at '/home/gidden/work/iiasa/message/properties_files/enedb.properties'
INFO:root:launching ixmp.Platform using config file at '/home/gidden/work/iiasa/message/properties_files/enedb.properties'
INFO:root:launching ixmp.Platform using config file at '/home/gidden/work/iiasa/message/properties_files/enedb.properties'
Nov 21, 2018 10:04:59 AM org.flywaydb.core.internal.util.VersionPrinter printVersion
INFO: Flyway 4.2.0 by Boxfuse
Nov 21, 2018 10:04:59 AM org.flywaydb.core.internal.util.VersionPrinter printVersion
INFO: Flyway 4.2.0 by Boxfuse
Nov 21, 2018 10:04:59 AM org.flywaydb.core.internal.util.VersionPrinter printVersion
INFO: Flyway 4.2.0 by Boxfuse
Nov 21, 2018 10:04:59 AM org.flywaydb.core.internal.util.VersionPrinter printVersion
INFO: Flyway 4.2.0 by Boxfuse
Nov 21, 2018 10:05:00 AM org.flywaydb.core.internal.dbsupport.DbSupportFactory createDbSupport
INFO: Database: jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3 (Oracle 12.1)
Nov 21, 2018 10:05:00 AM org.flywaydb.core.internal.dbsupport.DbSupportFactory createDbSupport
INFO: Database: jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3 (Oracle 12.1)
Nov 21, 2018 10:05:01 AM org.flywaydb.core.internal.command.DbValidate validate
INFO: Successfully validated 11 migrations (execution time 00:00.071s)
Nov 21, 2018 10:05:01 AM org.flywaydb.core.internal.dbsupport.DbSupportFactory createDbSupport
INFO: Database: jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3 (Oracle 12.1)
Nov 21, 2018 10:05:01 AM org.flywaydb.core.internal.dbsupport.DbSupportFactory createDbSupport
INFO: Database: jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3 (Oracle 12.1)
2018-11-21 10:05:01,384  INFO at.ac.iiasa.ixmp.Platform:111 - Welcome to the IX modeling platform!
2018-11-21 10:05:01,385  INFO at.ac.iiasa.ixmp.Platform:112 -  connected to database 'ixENE-DB@GP3'...
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:171: UserWarning: The constructor `mp.Scenario()` is deprecated, please use `ixmp.Scenario(mp, ...)`
  warnings.warn('The constructor `mp.Scenario()` is deprecated, '
Nov 21, 2018 10:05:01 AM org.flywaydb.core.internal.command.DbValidate validate
INFO: Successfully validated 11 migrations (execution time 00:00.040s)
2018-11-21 10:05:01,468  INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 1, runid: 18489)...
Nov 21, 2018 10:05:01 AM org.flywaydb.core.internal.command.DbValidate validate
INFO: Successfully validated 11 migrations (execution time 00:00.080s)
Nov 21, 2018 10:05:01 AM org.flywaydb.core.internal.command.DbValidate validate
INFO: Successfully validated 11 migrations (execution time 00:00.077s)
2018-11-21 10:05:01,620  INFO at.ac.iiasa.ixmp.Platform:111 - Welcome to the IX modeling platform!
2018-11-21 10:05:01,623  INFO at.ac.iiasa.ixmp.Platform:112 -  connected to database 'ixENE-DB@GP3'...
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:171: UserWarning: The constructor `mp.Scenario()` is deprecated, please use `ixmp.Scenario(mp, ...)`
  warnings.warn('The constructor `mp.Scenario()` is deprecated, '
2018-11-21 10:05:01,698  INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 1, runid: 18489)...
2018-11-21 10:05:01,785  INFO at.ac.iiasa.ixmp.Platform:111 - Welcome to the IX modeling platform!
2018-11-21 10:05:01,786  INFO at.ac.iiasa.ixmp.Platform:112 -  connected to database 'ixENE-DB@GP3'...
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:171: UserWarning: The constructor `mp.Scenario()` is deprecated, please use `ixmp.Scenario(mp, ...)`
  warnings.warn('The constructor `mp.Scenario()` is deprecated, '
2018-11-21 10:05:01,818  INFO at.ac.iiasa.ixmp.Platform:111 - Welcome to the IX modeling platform!
2018-11-21 10:05:01,821  INFO at.ac.iiasa.ixmp.Platform:112 -  connected to database 'ixENE-DB@GP3'...
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:171: UserWarning: The constructor `mp.Scenario()` is deprecated, please use `ixmp.Scenario(mp, ...)`
  warnings.warn('The constructor `mp.Scenario()` is deprecated, '
2018-11-21 10:05:01,881  INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 1, runid: 18489)...
2018-11-21 10:05:01,947  INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 1, runid: 18489)...
2018-11-21 10:05:02,002  INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
2018-11-21 10:05:02,105  INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 -  spatial and temporal disaggregation maps assignment
2018-11-21 10:05:02,129  INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 -  period mapping assignment
2018-11-21 10:05:02,144  INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 -  duration period assignment
2018-11-21 10:05:02,198  INFO at.ac.iiasa.ixmp.objects.Scenario:1826 - committing changes of Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18489)...
2018-11-21 10:05:02,378  INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
Traceback (most recent call last):
  File "foo.py", line 4, in <module>
    p.Scenario('MESSAGEix-GLOBIOM_BvR_OFR1', 'NPi2020_Net0')
  File "/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py", line 174, in Scenario
    return Scenario(self, model, scen, version, scheme, annotation, cache)
  File "/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py", line 460, in __init__
    self._jobj = mp._jobj.getScenario(model, scenario)
jpype._jexception.IxExceptionPyRaisable: at.ac.iiasa.ixmp.exceptions.IxException: This Scenario is currently locked by user gidden
2018-11-21 10:05:02,513  INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
Traceback (most recent call last):
  File "foo.py", line 4, in <module>
    p.Scenario('MESSAGEix-GLOBIOM_BvR_OFR1', 'NPi2020_Net0')
  File "/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py", line 174, in Scenario
    return Scenario(self, model, scen, version, scheme, annotation, cache)
  File "/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py", line 460, in __init__
    self._jobj = mp._jobj.getScenario(model, scenario)
jpype._jexception.IxExceptionPyRaisable: at.ac.iiasa.ixmp.exceptions.IxException: This Scenario is currently locked by user gidden
2018-11-21 10:05:02,642  INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
Traceback (most recent call last):
  File "foo.py", line 4, in <module>
    p.Scenario('MESSAGEix-GLOBIOM_BvR_OFR1', 'NPi2020_Net0')
  File "/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py", line 174, in Scenario
    return Scenario(self, model, scen, version, scheme, annotation, cache)
  File "/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py", line 460, in __init__
    self._jobj = mp._jobj.getScenario(model, scenario)
jpype._jexception.IxExceptionPyRaisable: at.ac.iiasa.ixmp.exceptions.IxException: This Scenario is currently locked by user gidden
2018-11-21 10:05:03,686  INFO at.ac.iiasa.ixmp.objects.Scenario:601 - done updating Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18489, version: 1)!
2018-11-21 10:05:03,692  INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 -  spatial and temporal disaggregation maps assignment
2018-11-21 10:05:03,693  INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 -  period mapping assignment
2018-11-21 10:05:03,698  INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 -  duration period assignment
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:468: UserWarning: Using `ixmp.Scenario` for MESSAGE-scheme scenarios is deprecated, please use `message_ix.Scenario`
  warnings.warn('Using `ixmp.Scenario` for MESSAGE-scheme scenarios '
Out[4]: [0, 1, 1, 1]

[danielhuppmann]

See the warning message
/home/gidden/.local/lib/python3.5/site-packages/ixmp/core.py:468: UserWarning: Using `ixmp.Scenario` for MESSAGE-scheme scenarios is deprecated, please use `message_ix.Scenario` warnings.warn('Using `ixmp.Scenario` for MESSAGE-scheme scenarios '

Try using message_ix.Scenario().

[danielhuppmann]

More to the point, the function updateMsgScheme() is called at every loading of a MESSAGE-scheme scenario, and it does a check-out, validates the version (sets and parameters), and then either discards (if no changes were made) or commits the changes.

Having a lag of one second between each process should do the trick.

[zikolach]

@danielhuppmann why we cannot do blocking there instead letting users shoot into their leg?

[danielhuppmann]

@zikolach, the blocking on the database side is exactly what is causing the problem.

[gidden]

I updated foo.py to look like

import ixmp
import message_ix

p = ixmp.Platform()
message_ix.Scenario(p, 'MESSAGEix-GLOBIOM_BvR_OFR1', 'NPi2020_Net0')

The error persists, unfortunately.

[gidden]

So, to get the conversation back on track, here is my understanding of the issue:

This is an old scenario with scheme == 1.0.0. It needs to be updated to 1.1.0.

The hypothesis is that by loading it once, the scheme is updated and committed. Thus all should be fine.

However, this hypothesis is incorrect. When loading it once (n=1 above), all is well. Then it is attempted to be loaded multiple times ( n > 1). In this second round, again commits are generated.

So, what do we think is the best way to address this issue? I agree that explicitly putting in a sleep would work, but that, I would argue, is highly unsatisfactory. I would expect to be able to concurrently load (read only) many instances of a scenario as long as its scheme is up to date. Right?

[danielhuppmann]

Well, the hypothesis is partially correct. Touching a scenario generated with v1.0 with an MESSAGEix installation v1.1 will automatically upgrade the scenario.

The way this was implemented is the process described above - check-out, test whether upgrades are necessary, discard or commit. This seems to take about one second if no upgrade is made on a full-scale MESSAGE scenario, not sure how much more if an upgrade is made.

Options:

1. Change the function updateMsgScheme() to only do the check-out if upgrades are made. I'm not sure if this actually works and whether changes are required down the rabbit hole.
2. Add an explicit version tag to the RUN table and test for that instead of the current workflow. Question is whether this will require a more elaborate version-control-and-upgrade process, "flyway"-style. Definitely a rabbit hole.

[gidden]

Ok, @danielhuppmann, I think I'm starting to get it. I am still confused on one point.

In the above example, we run once a file to load a v1.0 scenario. During the load, a commit is made (presumably to update it to V1.1).

Next, in a new process, we load that same scenario multiple times. A commit still occurs in the first process to access the DB. This implies to me that the V1.1 update was somehow not saved.

Am I understanding correctly or no?

[gidden]

Is it possible that the updated version is not being labeled default? Thus, on the next load, you still get the original stale version?

[gidden]

Ok, looking over @OFR-IIASA's shoulder I think this is indeed the issue. In each of the above examples, the "default" is always version 1, e.g.,: INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 1, runid: 18489

Thus it is always getting a stale version here. Is this how we expect it to work? I thought there was an automatic setting to default somewhere in the pipeline of a new clone?

[danielhuppmann]

Ok, way too many issues that are being tangled up in this discussion...

From the conversation so far, I have no reason to believe that the upgrade to v1.1 doesn't work as intended - but you can test this by looking whether any new set or parameter from the hackathon developments exist in the scenario after touching it with MESSAGEix v.1.1.

What is confusing (and a minor bug) is that a message is written to the log file about updating a scenario even if no change to the scenario is saved to the db. The commit() function on the database does verify (afaik) whether any change has been made and only touches the db if that is true.

What needs to be double-checked is whether an entry is added to the CHANGELOG table every time a scenario is loaded, even if no change was made by the upgrade. You can verify this by looking at the changelog table for scenario id=18489, there should be one entry "Upgrade to MESSAGEix scheme version 1.1" (or similar). I tested this (in an unstructured way) prior to making the lastest ixmp PR. That would be a medium bug if the log entry was added more than once.

As I tried to explain earlier, the "checking whether an upgrade is necessary" function performs a check-out, so no other process can start loading the scenario while that verification is in progress (~ 1 sec).

Now, to the other issues: the version number you see is the identification from multiple runs with a particular model/scenario name. It has nothing to do with the MESSAGEix version number.

Also, the upgrade to MESSAGEix v1.1 does not clone a scenario (it just makes changes to an existing scenario) and does not have any impact on whether that scenario is defined as default or not.

[gidden]

Yes, agreed, we've got a few issues wound up in this, notably:

1. Reading is not strictly thread-safe (due to the fact that check outs occur, which is similar to a write in thread-safety even if no writing occurs)
2. Model/scenario combinations are allowed to have no defaults (thus I presume it will always grab the version: 1 dataset [but we are seeing inconsistencies, I don't know how this works])
3. Making changes to to the schema, e.g., updating from V1.0 to V1.1, does not update the default status of the updated scenario (i.e., V1.0 will still be the default)

I should note, I don't know which/if any of these should be addressed, simply that these are the root causes of about 6 hours of investigations/headaches here.

[danielhuppmann]

Re item 3 in the list above - this is nonsense. It confuses the model/scenario version number with the MESSAGEix version number.

[OFR-IIASA]

just to elaborate on Matts 2nd point from above. Looking in the database I observe the following:

This clearly shows that the default is not set for version 42, in fact, none of the version of this scenario have a default set, yet it is clear that this is actually loaded when using it in another process. This begs the question, why version 42, if there are also older and newer version?
__
2018-11-20 16:05:03,749 INFO at.ac.iiasa.ixmp.Platform:108 - Welcome to the IX modeling platform!
2018-11-20 16:05:03,750 INFO at.ac.iiasa.ixmp.Platform:109 - connected to !...
2018-11-20 16:05:03,847 INFO at.ac.iiasa.ixmp.objects.Scenario:227 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR|NPi2020_Net0' by version id (version: 42, runid: 18473)...
2018-11-20 16:05:04,245 INFO at.ac.iiasa.ixmp.objects.Scenario:249 - done loading Scenario from the database!
2018-11-20 16:05:04,254 INFO at.ac.iiasa.ixmp.objects.Scenario:400 - spatial and temporal disaggregation maps assignment
2018-11-20 16:05:04,254 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for set 'map_spatial_hierarchy' from database...
2018-11-20 16:05:04,265 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for set 'map_node' from database...
2018-11-20 16:05:04,272 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for set 'map_temporal_hierarchy' from database...
2018-11-20 16:05:04,279 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for set 'map_time' from database...
2018-11-20 16:05:04,287 INFO at.ac.iiasa.ixmp.objects.Scenario:530 - period mapping assignment
2018-11-20 16:05:04,287 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for set 'cat_year' from database...
2018-11-20 16:05:04,298 INFO at.ac.iiasa.ixmp.objects.Scenario:557 - duration period assignment
2018-11-20 16:05:04,299 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for parameter 'duration_period' from database...
2018-11-20 16:05:04,322 DEBUG at.ac.iiasa.ixmp.database.DbDAO:1744 - loading elements for variable 'OBJ' from database...
2018-11-20 16:05:04,337 INFO at.ac.iiasa.ixmp.objects.Scenario:227 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR|noBCCS' by version id (version: 0, runid: 18473)...
__

[zikolach]

@OFR-IIASA https://github.com/iiasa/ixmp_source/blob/4f96133a8ad152aa6aadf9436ab7bb3010f0c0de/src/main/java/at/ac/iiasa/ixmp/database/DbDAO.java#L235

It should be 48 (for now) according to select * from run where id = (select max(id) from run where MODEL_ID=1206 and SCEN_ID=6014 and STATUS >=0)

[danielhuppmann]

As indicated by @zikolach, it uses the run with the highest version number if no default is set...

But in the case posted by @OFR-IIASA, see

2018-11-20 16:05:03,847 INFO at.ac.iiasa.ixmp.objects.Scenario:227 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR|NPi2020_Net0' by version id (version: 42, runid: 18473)...

It says that you specially select version 42...

[OFR-IIASA]

@zikolach yes, that could be true now, but I believe that 42 could have been the most recent version at the time. But is this then the expected behaviour? If there is no default set, always the most recent version is used? @danielhuppmann I dont specify a version in the command when loading the scenario (just: message_ix.Scenario(mp, model_name, scenario_name, cache=True, first_model_year=2030)

[zikolach]

@OFR-IIASA yes - according to code it uses maximum version number if no default version found (see link I posted above)

[danielhuppmann]

@OFR-IIASA, at least when I wrote the different functions for loading a scenario, the logging message

loading Scenario 'model|scenario' by version id (version: x, runid: x)`

was intended for ixmp.Scenario(model, scenario, version), while ixmp.Scenario(model, scenario) was showing a message like

loading default version of Scenario 'model|scenario' (version: x, runid: x)`.

But maybe this got jumbled at some point.

[OFR-IIASA]

@danielhuppmann so, here are the two statements i execute (no version of the scenario has a default set, which is different to the example you gave above - so this only serves for clarfication when there is no default set)
scen = message_ix.Scenario(mp, "MESSAGEix-GLOBIOM_BvR_OFR1", "NPi2020_Net0")
__
2018-11-21 16:50:40,469 INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 2, runid: 18494)...
2018-11-21 16:50:40,669 INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
2018-11-21 16:50:40,693 INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 - spatial and temporal disaggregation maps assignment
2018-11-21 16:50:40,705 INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 - period mapping assignment
2018-11-21 16:50:40,710 INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 - duration period assignment
2018-11-21 16:50:40,718 INFO at.ac.iiasa.ixmp.objects.Scenario:1826 - committing changes of Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18494)...
2018-11-21 16:50:41,525 INFO at.ac.iiasa.ixmp.objects.Scenario:601 - done updating Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18494, version: 2)!
2018-11-21 16:50:41,653 INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 - spatial and temporal disaggregation maps assignment
2018-11-21 16:50:41,653 INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 - period mapping assignment
2018-11-21 16:50:41,654 INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 - duration period assignment
__

scen = message_ix.Scenario(mp, "MESSAGEix-GLOBIOM_BvR_OFR1", "NPi2020_Net0", version=2)
__
2018-11-21 16:50:41,686 INFO at.ac.iiasa.ixmp.objects.Scenario:218 - loading Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' by version id (version: 2, runid: 18494)...
2018-11-21 16:50:41,884 INFO at.ac.iiasa.ixmp.objects.Scenario:241 - done loading Scenario from the database!
2018-11-21 16:50:41,896 INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 - spatial and temporal disaggregation maps assignment
2018-11-21 16:50:41,906 INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 - period mapping assignment
2018-11-21 16:50:41,909 INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 - duration period assignment
2018-11-21 16:50:41,914 INFO at.ac.iiasa.ixmp.objects.Scenario:1826 - committing changes of Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18494)...
2018-11-21 16:50:42,644 INFO at.ac.iiasa.ixmp.objects.Scenario:601 - done updating Scenario 'MESSAGEix-GLOBIOM_BvR_OFR1|NPi2020_Net0' to the database (runid: 18494, version: 2)!
2018-11-21 16:50:42,650 INFO at.ac.iiasa.ixmp.objects.MsgScenario:457 - spatial and temporal disaggregation maps assignment
2018-11-21 16:50:42,650 INFO at.ac.iiasa.ixmp.objects.MsgScenario:573 - period mapping assignment
2018-11-21 16:50:42,650 INFO at.ac.iiasa.ixmp.objects.MsgScenario:599 - duration period assignment
__

[zikolach]

@OFR-IIASA here is when it outputs to log and here is implementation of isDefaultVersion(runId) method

[gidden]

Hi all, I have created two separate issues brought up in this thread. If you think there are other actionable issues here, please open them as new issues. Closing now as we have found the root cause of the observed behavior.